I am seeing an issue when using Serial1.readBytes() that I have bisected down to this commit.

I'm using the serial port to send a query to a sensor device, which then responds with a fixed size (1024 byte) packet. I do this over and over. After this commit, it sometimes returns from readBytes() claiming it has read 1024 bytes, but it could not have (see attached pictures).

So first pic is a good transaction. Channel 5 is a GPIO that goes high while I enter my readBytes() call, then is set low again when I have successfully read 1024 bytes. As expected it does not go low until after all bytes have been transmitted. (Note Channel 6 is labelled 'tx' from the point of view of the sensor, not the ESP32).

Here's what happens fairly frequently after this commit. As you can see, Channel 5 goes back low again prior to the data even arriving at the pin. The software is getting data from somewhere, but it cannot possibly be the uart as the data hasn't arrived yet.

Reverting this commit, and it works as expected.

@dflogeras have you looked at the bytes that it claims it have received?
Can you share what the differences are and from which byte it happens?

@dflogeras also if you can play with uart->dev->idle_conf.tx_idle_num = 0; and try a positive value like 1 or 10?

@dflogeras
I am trying to simulate your environment so see if I can replicate the issue.
Out of first tests I have no problems here.
At what baudrate are you sending ?

PS Are you able to do local patches to esp-hal-uart.c to verify solutions ?

I am running it at 460800 baud during that phase.

I can certainly patch esp-hal-uart.c if it is built as part of the Arduino build process. I am working on another job today, but will get back to this tomorrow and can try tx_idle_num changes.

I didn't diagnose down to the byte yet, for I will need to change my test setup for triggering on when it happens, which I can't do until at least tomorrow.

@dflogeras
Can you update uint8_t uartRead(uart_t* uart), line 295 of esp-hal-uart.c to :

uint8_t uartRead(uart_t* uart)
{
    if(uart == NULL || uart->queue == NULL) {
        return 0;
    }
    uint8_t c;
    UART_MUTEX_LOCK();
    if ((uxQueueMessagesWaiting(uart->queue) == 0) && (uart->dev->status.rxfifo_cnt > 0))
    {
        while(uart->dev->status.rxfifo_cnt || (uart->dev->mem_rx_status.wr_addr != uart->dev->mem_rx_status.rd_addr)) {
            c = uart->dev->fifo.rw_byte;
            xQueueSend(uart->queue, &c, 0);
        }
    }
    UART_MUTEX_UNLOCK();
    if(xQueueReceive(uart->queue, &c, 0)) {
        return c;
    }
    return 0;
}

And see if there is different behavior ?

@me-no-dev :
This way I have the (uart->dev->status.rxfifo_cnt > 0)) check within the UART_MUTEX_LOCK();

Patching esp32-hal-uart.c as above: now instead of uartRead() returning early with incorrect data, now it always times out with a short count (even though I can see the sensor is sending 1024 bytes on the logic analyzer). Seemed to be always in the 700s, but not always the same number of bytes.

Trying values 1 and 10 for tx_idle_num both still exhibited the original behaviour (returning a full read, but clearly early and with incorrect data).

@dflogeras
I am running the test using two ESP32's.
Think I reproduced the issue, using both the original as the patched version.
Needed to go to 921600 baud to get it faulting.

First observation : The first byte being wrong in a message is always nr 256.
Is there a possibility that you can verify if that is at your side too ?

@dflogeras
With this uartRead() I have no fails. Can you test in your environment ?

uint8_t uartRead(uart_t* uart)
{
    if(uart == NULL || uart->queue == NULL) {
        return 0;
    }
    uint8_t c;
    UART_MUTEX_LOCK();
    //disable interrupts
    uart->dev->int_ena.val = 0;
    uart->dev->int_clr.val = 0xffffffff;
    if ((uxQueueMessagesWaiting(uart->queue) == 0) && (uart->dev->status.rxfifo_cnt > 0))
    {
        while(uart->dev->status.rxfifo_cnt || (uart->dev->mem_rx_status.wr_addr != uart->dev->mem_rx_status.rd_addr)) {
            c = uart->dev->fifo.rw_byte;
            xQueueSend(uart->queue, &c, 0);
        }
    }
    //enable interrupts
    uart->dev->int_ena.rxfifo_full = 1;
    uart->dev->int_ena.frm_err = 1;
    uart->dev->int_ena.rxfifo_tout = 1;
    uart->dev->int_clr.val = 0xffffffff;
    UART_MUTEX_UNLOCK();
    if(xQueueReceive(uart->queue, &c, 0)) {
        return c;
    }
    return 0;
}

I will check when I am home later in the day.

In the meantime, can you verify that the problem goes away for you by reverting this commit?

Ok, will verify and report. Probably tomorrow.

OK. Your last patch on top of this commit had the same behaviour as your previous patch: timeouts after the default 1s with short byte count (in the 730-750 bytes range when I asked for 1024)

Your previous comment of needing to go to 800kBaud to reproduce made me think of something else though. I forgot to mention, that I am running my CPU at 80MHz (for power consumption). If I switch to 160 or 240, I get the full data (both this commit unpatched, as well as with your latest patch).

What I don't know is what that means. Is running the CPU faster just hiding a race condition? I am hard pressed to believe that a 80MHz CPU cannot keep up with a 400kBaud (45 kBytes/s), while doing almost nothing else.

@dflogeras Good to mention.
With 80Mhz and 460800 baud I get rxFifo overflow errors.
I enabled the interrupt for this :

void uartEnableInterrupt(uart_t* uart)
{
    UART_MUTEX_LOCK();
    uart->dev->conf1.rxfifo_full_thrhd = 112;
    uart->dev->conf1.rx_tout_thrhd = 2;
    uart->dev->conf1.rx_tout_en = 1;
    uart->dev->int_ena.rxfifo_full = 1;
    uart->dev->int_ena.frm_err = 1;
    uart->dev->int_ena.rxfifo_tout = 1;
    uart->dev->int_ena.rxfifo_ovf = 1; // add for ovf test
    uart->dev->int_clr.val = 0xffffffff;

    esp_intr_alloc(UART_INTR_SOURCE(uart->num), (int)ESP_INTR_FLAG_IRAM, _uart_isr, NULL, &uart->intr_handle);
    UART_MUTEX_UNLOCK();
}

Add check in isr

static void IRAM_ATTR _uart_isr(void *arg)
{
    uint8_t i, c;
    BaseType_t xHigherPriorityTaskWoken;
    uart_t* uart;
    
    uart = &_uart_bus_array[1];        // 0 for serial, 1 for serial1, 2 for serial2
    if (uart->dev->int_st.rxfifo_ovf)  // overflow occurred
    {
    	uart->dev->int_clr.rxfifo_ovf = 1; // clear overflow interrupt bit
    	digitalWrite(27, !digitalRead(27));
    }

    for(i=0;i<3;i++){

And i see the GPIO 27 toggle -> loosing chars because of fifo overflow.
Changing to 160Mhz -> no ovf

Your situation now with readbyte() timeout is explained by this.
Earlier issue which showed "additional" chars is solved by the update to the patch.

Ok good we're on the same page now. So, the hardware literally cannot keep up @ 80MHz?

Also, to put it another way, why was it not losing characters prior to this commit?

It's the software which can't keep up at 80Mhz, that should empty the fifo.

Sorry, yes that's what I mean, the hardware being the CPU @ 80Mhz

That still doesn't explain why it was (seemingly) working prior to this.

Will check on that in the coming days.

@hreintke @dflogeras you need a minimum number of cpu cycle to service an interrupt. With the I2C subsystem, I adjust the FIFO thresholds inversely with cpu clock and limit maximum I2C bus clock at lower cpu speeds. It seems to work at 800k Baud and 112 as Fifo Full Threshold, with Fifo Threshold at 112 that leaves 16 byte periods to start emptying the fifo before overflows happen. That calculates to 200us with a 80MHz clock that is 16k clock cycles. The interrupt would trigger about every 1.4ms. It looks like that is not enough.

Try reducing the Fifo threshold inversely with cpu clock and Baud, If 112 works at 240mhz and 800KHz and you divide cpu by 3, divide threshold by 3, So, 112 becomes 38. It still uses the full Fifo, but it gives you additional time to react.

Chuck.

@stickbreaker I agree with your assessment of reducing the 'high water alarm' on the fifo.

However in practice it didn't fix the problem I am seeing. I reduced the threshold to 32 (in addition to @hreintke last patch from the above comment), and it received even less short-count data after timing out.

@dflogeras :
I cleaned and rechecked my development environment and am checking exact timings.

Just to be sure : Are you emptying the uart buffers with while Serial.available() { Serial.read()} before requesting the new data ?

Edit : test result
All at 460800 baud
Non patched, 160Mhz, 112 fifo, OK
Non patched, 80 Mhz, 112 fifo, Not OK
Non patched, 80 Mhz, 64 fifo, OK
Patched, 160Mhz, 112 fifo, OK
Patched 80Mhz, 112 fifo, OK
Patched, 80 Mhz, 64 fifo, OK

I attached master and slave test programs.

SerialMaster.txt
SerialSlave.txt

@stickbreaker @me-no-dev
I have been measuring interrupt service times on uart .
This is the full ISR :

static void IRAM_ATTR _uart_isr(void *arg)
{
    uint8_t i, c;
    BaseType_t xHigherPriorityTaskWoken;
    uart_t* uart;

    for(i=0;i<3;i++){
        uart = &_uart_bus_array[i];
        if(uart->intr_handle == NULL){
            continue;
        }
        uart->dev->int_clr.rxfifo_full = 1;
        uart->dev->int_clr.frm_err = 1;
        uart->dev->int_clr.rxfifo_tout = 1;
        if (i==1) digitalWrite(26,HIGH);
        while(uart->dev->status.rxfifo_cnt || (uart->dev->mem_rx_status.wr_addr != uart->dev->mem_rx_status.rd_addr)) {
            c = uart->dev->fifo.rw_byte;
            if(uart->queue != NULL && !xQueueIsQueueFullFromISR(uart->queue)) {
                xQueueSendFromISR(uart->queue, &c, &xHigherPriorityTaskWoken);
            }
        }
        if (i==1) digitalWrite(26,LOW);
    }

    if (xHigherPriorityTaskWoken) {
        portYIELD_FROM_ISR();
    }
}

The detail :

            if(uart->queue != NULL && !xQueueIsQueueFullFromISR(uart->queue)) {
                xQueueSendFromISR(uart->queue, &c, &xHigherPriorityTaskWoken);
            }

has a check on full queue before sending to queue.
But xQueueSendFromISR returns false when trying to write to a full queue.
When updated to :

        if(uart->queue != NULL) {
            xQueueSendFromISR(uart->queue, &c, &xHigherPriorityTaskWoken);
        }

It does have the same functionality.

ISR Timing 
80 Mhz, 112 fifo, current version : 1.4 msec
80 Mhz, 112 fifo, updated version : 0.7 msec
160 Mhz, 112 fifo, current version : 0.55 msec
160 Mhz, 112 fifo, updated version : 0.32 msec

What is your opinion on this update ?

@hreintke

static void IRAM_ATTR _uart_isr(void *arg)
{
    uint8_t i, c;
    BaseType_t xHigherPriorityTaskWoken = FALSE;
    uart_t* uart;

    for(i=0;i<3;i++){
        uart = &_uart_bus_array[i];
        if(uart->intr_handle == NULL){
            continue;
        }
        uart->dev->int_clr.rxfifo_full = 1;
        uart->dev->int_clr.frm_err = 1;
        uart->dev->int_clr.rxfifo_tout = 1;
        if (i==1) digitalWrite(26,HIGH);
        while(uart->dev->status.rxfifo_cnt || (uart->dev->mem_rx_status.wr_addr != uart->dev->mem_rx_status.rd_addr)) {
            c = uart->dev->fifo.rw_byte;
            if(uart->queue != NULL ) {
                xQueueSendFromISR(uart->queue, &c, &xHigherPriorityTaskWoken);
            }
        }
        if (i==1) digitalWrite(26,LOW);
    }

    if (xHigherPriorityTaskWoken) {
        portYIELD_FROM_ISR();
    }
}

I don't see any problem with your suggested changes. My only question relates back to the choice of servicing all three UARTs whenever one of them triggers an interrupt. The for() loop. I haven't convinced Me-No-Dev yet 😀

Remember to remove your debug (digitalWrite()) before you post the merge request.
Chuck.

I just had a stupid idea, the current code drops characters when the queue becomes full. What do you think about a condition to stop emptying the fifo if the fifo is lower than the interrupt trigger and the queue is full, allow foreground a chance to process and save the chars in the fifo?

This code is UNTESTED and Just off-the-cuff, to BBW(Buyer Be Ware!)

static void IRAM_ATTR _uart_isr(void *arg)
{
    uint8_t i, c;
    BaseType_t xHigherPriorityTaskWoken = FALSE;
    uart_t* uart;

    for(i=0;i<3;i++){
        uart = &_uart_bus_array[i];
        if(uart->intr_handle == NULL){
            continue;
        }

  // adjust rxfifo empty point based on latency between interrupt triggering and ISR firing
  // minimum free space of 8 characters
        if (uart->dev->int_st.rxfifo_full ) { //only adjust if this UART triggered fifoFull
            if( uart->dev->status.rxfifo_cnt > uart->dev->conf1.rxfifo_full_thrd){ // delayed service
                if(  (128 - uart->dev->status.rxfifo_cnt ) < 8 ) { // almost overflowed Fifo
                    if (uart->dev->conf1.rxfifo_full_thrhd > 32 ) { // min fifo level
                        uart->dev->conf1.rxfifo_full_thrhd -= 1; // trigger earlier 
                    }
                }    
            }
            else if ( uart->dev->conf1.rxfifo_full_thrd <120){// under utilizing Fifo
                uart->dev->confg1.rxfifo_full_thrd += 1;
            }
        }
// end of fifo trigger adjust

        uart->dev->int_clr.rxfifo_full = 1;
        uart->dev->int_clr.frm_err = 1;
        uart->dev->int_clr.rxfifo_tout = 1;
        if (i==1) digitalWrite(26,HIGH);
        while(uart->dev->status.rxfifo_cnt || (uart->dev->mem_rx_status.wr_addr != uart->dev->mem_rx_status.rd_addr)) {
            c = uart->dev->fifo.rw_byte;
            if(uart->queue != NULL ) {
                if ( !xQueueSendFromISR(uart->queue, &c, &xHigherPriorityTaskWoken)){
                // queue is full, exit if fifo level is below fifo trigger
                    if( uart->dev->status.rxfifo_cnt <   uart->dev->conf1.rxfifo_full_thrhd )
                       continue;
                }
              }
        }
        if (i==1) digitalWrite(26,LOW);
    }

    if (xHigherPriorityTaskWoken) {
        portYIELD_FROM_ISR();
    }
}

@dflogeras might be seeing the character loss because the queue is overflowing, not because the fifo is overflowing. If the interrupt is triggering more often then his fore ground process does not have a chance to process before the Serial() queue is overflowed.

Chuck.

@stickbreaker
Will go in more detail through your suggestion but the problems is that you have to get the char from the uart c = uart->dev->fifo.rw_byte; before you know that the buffer is full.
That character is always lost.

You are correct. The only way not to loose that char would be to check for QueueFull before attempting the add. But, based on your results. That check before call is expensive in time.

ISR Timing
80 Mhz, 112 fifo, current version : 1.4 msec
80 Mhz, 112 fifo, updated version : 0.7 msec
160 Mhz, 112 fifo, current version : 0.55 msec
160 Mhz, 112 fifo, updated version : 0.32 msec

One way around this would be to store the queue size in UART record and use
UBaseType_t uxQueueMessagesWaitingFromISR(const QueueHandle_t xQueue) to see the available space

//cut
        uart->dev->int_clr.frm_err = 1;
        uart->dev->int_clr.rxfifo_tout = 1;
        if (i==1) digitalWrite(26,HIGH);
        size_t freeCount = 0;
        if(uart->queue ) {
            freeCount = uart->queueSize - uxQueueMessagesWaitingFromISR(uart->queue );
        }
        while(uart->dev->status.rxfifo_cnt || (uart->dev->mem_rx_status.wr_addr != uart->dev->mem_rx_status.rd_addr)) {
            if(freeCount-- > 0) {
                c = uart->dev->fifo.rw_byte;
                xQueueSendFromISR(uart->queue, &c, &xHigherPriorityTaskWoken);
            )
            else {
                // queue is full, exit if fifo level is below fifo trigger
                    if( uart->dev->status.rxfifo_cnt <   uart->dev->conf1.rxfifo_full_thrhd ){
                        break; // stop emptying fifo, Queue is full, but fifo has room
                    }
                    else { // empty one char from FIFO and discard
                         c = uart->dev->fifo.rw_byte;
                    }
            }
        }
        if (i==1) digitalWrite(26,LOW);
    }

Oops, used continue when I meant break 😬

For this code to work, the size_t queueSize; needs to be added to the uart structure.

Chuck.

This is better inner loop code:'

    while(uart->dev->status.rxfifo_cnt || (uart->dev->mem_rx_status.wr_addr != uart->dev->mem_rx_status.rd_addr)) {
        c = uart->dev->fifo.rw_byte;
        if(freeCount-- > 0) {
          xQueueSendFromISR(uart->queue, &c, &xHigherPriorityTaskWoken);
        }
        else {
                // queue is full, exit if fifo level is below fifo trigger
            if( uart->dev->status.rxfifo_cnt <   uart->dev->conf1.rxfifo_full_thrhd ) {
                break; // stop emptying fifo, Queue is full, but fifo has room
            }
        }
    }
    if (i==1) digitalWrite(26,LOW);

Always have to empty at least one char from fifo. So, it will only loose the char if rxFifo_Full interrupt triggered and the Queue is already full.

Chuck.

I can confirm that just by removing the xQueueIsQueueFullFromISR from the isr code, I can now keep my head above water @ 80MHz.

@stickbreaker
I was thinking on saving the already taken char in the uart struct.
When a new interrupt comes, first try the saved char, if that succeeds, take next char and give that a try.
That prevents the need of keeping track of queue size.
I'll do some testing on that, probably tomorrow.

What also might help is moving to Ringbuffer
https://docs.espressif.com/projects/esp-idf/en/latest/api-reference/system/freertos_additions.html
That has the possibility to add multiple chars in one call, further limiting the number of queue calls within the isr.

@dflogeras Have you verified where the loss of data was happening in your case? Was the loss because of rxfifo overflow or because the Queue was full?

Chuck.

@hreintke saving the "extra" character inside the uart structure would create other requirement, you would have to test if the "extra" character is valid and move it during every read() and available(), isr().

Another possible problem with leaving the data in the rxfifo is when does rxfifo_tout trigger? Would it continuously re-trigger every tout period until the rxfifo is empty?

All of my coding is untested theoretical. So, there are probably many hidden pitfalls.

Chuck.

Submitted PR #3713 with bugfix and isr improvement.

@stickbreaker
Another day, new thoughts on not discarding chars when queue is full.
In principle this is an application issue : Not emptying the buffer quick enough as chars are coming in.
It can be improved somewhat by additional checks but ...

• It is no full solution, only delaying the issue
• it makes the isr more complex
• The application developer has easy solutions available
  • Lower the baudrate
  • Increase the buffer size HardwareSerial::setRxBufferSize
  • Increase cpu speed

My suggestion would be to leave it as is.

On fifo size.
I would set the fifo size at `Serial.begin()' depending on baudrate and cpu speed and not change it during isr processing.
Maybe add a method to Serial to set it different from the default.

What is your opinion ?

I would set the fifo size at `Serial.begin()' depending on baudrate and cpu speed and not change it during isr processing.

It should change as part of the CPU frequency callback which adjusts the baud rate parameters as well. It should not be adjusted inside the ISR.

@hreintke @atanisoft I agree with both of you, my code would add complexity and uncertainty. Neither of which is good in a foundational driver.

@hreintke maybe have some persistent flag "queueOverfow", or a log_e("Overflow uart(%d)",i); so the user gets some notification that their foreground task is not processing the queue quick enough?

@atanisoft any idea on a formula to generate the rxfifo_full value? the 112 was me-no-dev's empirical solution. I was hoping that my auto adjuster code would generate a value that would match the users application.

Chuck.

solved #2004